OpenVPN Roadwarrior Connections Log

I connected to my vpn this morning as connection name josh for a few minutes but it does not show in the log. Do I need to wait 24 hours for this info to appear?

The clock goes midnight to midnight on the same day. So zero seconds total. Change the To: Day: to the 18th.

1 Like

@jon

I looked at the log again today. Both From: and To: selections are 18 jan 2022 but the report shows entries of the previous day. That is not right.

IMO, the From: should be 00:00:00 and To: 23:59:59 of date selected.

I just had a look through the perl code for the OpenVPN Roadwarrior Connections Log.

The From time is 00:00:00 and the end time is 86399 secs after the start time which comes out at 23:59:59 unless you are checking today’s date when the end time will be the current time. So it should be working as Paul is expecting.

In the code I did find that if you have a connection that is connected from a date before that is not disconnected until the day you are looking at then that connection will be shown. So if you had a connection that started on Jan 17th and was disconnected on Jan 18, it will show up on both the 17th and the 18th dates. I found this in some of my logs.

The only way I found a date being shown in the logs when the date in the From: and To: had been changed was when I changed the dates but had not yet pressed Update.

Please don’t take this the wrong way Paul, but you had pressed the Update button after changing the dates. If yes then that would look like a bug but I have not been able to duplicate it in any of my logs.

I just opened the Log, did not touch the dates, selected connection name: josh and clicked update.

Josh disconnected yesterday at 14:47

Do the same connections show up if you change to 17th and update and what happens when you go back to the 18th then.

My logs don’t have anything from yesterday so I can’t do a check of opening up the page without changing any dates.

If after you change to 17th and update and then back to 18th and update the connections no longer show on the 18th that would suggest a bug with the default date being set when you open up the page without changing any dates.

Let us know what you find. I will try and create some data for today and then check it tomorrow to see if I can duplicate it.

Selected From:17, selected josh, update, I see 3 entries all from yesterday.

Selected From:18, selected josh, update, I see the same 3 entries.

Selected From:18 To:19, josh, update, same 3 entries.

I can ask josh to connected for 5 min today and then see what the Logs says.

If the connection spills into the next day how will that be reported?

eg 
              17 jan                 18 jan
--------------23:55------+-----------00:10---------------
              connect                disconnect

If I ask show me report for the 17th, josh should be reported for 5 min
if I ask show me report for the 18th, josh should be reported for 10 min.

If the connection goes from the 17th to 18th then the same message will be seen in the report for the 17th and the 18th.

That is what i had with some of my data.

I have created some openvpn data on a vm testbed system. I will check that tomorrow to see if it shows the 18th data on the 19th as set by default when I open the page up.

I have already tried setting the date to the 19th but it came back empty.

You definitely have something peculiar going on. Will see if I can duplicate it tomorrow. If not then it is a bit difficult because it is not clear why it is doing it.

This screenshot shows a connection that went from 18th to 19th Nov 2021 and you can see it at the bottom of the list.
If I chose 19th then the screen would have that entry at the top and the other ones were from 19th only.

I don’t know what would happen if you had a connection that went over three days. It would definitely show up in the first and third day because the code also looks for connections that get connected on the selected day or get disconnected on that day and then shows the whole connection.
I am not sure what would happen in the 2nd day of a three day connection.

Today the 19th I looked at the log again. The settings are from 18th to 19th but it shows data from the 17th. Something in the filtering is not ok. josh was not connected for >24 hr to spill over to the next day.

Hi Paul

I just went and checked the data in the log that I created yesterday on my vm CU162 system. I did what you described. Went to the log page, didn’t touch the date. Changed the connection name to the one I used yesterday and pressed Update. The table stayed empty with no entries. I changed the date to 18th and it then showed the connections I ran yesterday.

There is definitely something wrong in your IPFire .

I would suggest to do a diff between the
/srv/web/ipfire/cgi-bin/logs.cgi/ovpnclients.dat
file on your system and the one in the IPFire repository for CU162

https://git.ipfire.org/?p=ipfire-2.x.git;a=blob;f=html/cgi-bin/logs.cgi/ovpnclients.dat

to see if something has got corrupted causing he difference.

If they are the same then I don’t know why it gives the effect you see and I am not able to duplicate it! Sorry.

how do I get that file raw ? nevermind, found it.

I guess I have an extra newline at the very end. Removed that last newline and diff came clean.

[root@ipfire ~]# diff adolf /srv/web/ipfire/cgi-bin/logs.cgi/ovpnclients.dat 
390d389
< 
[root@ipfire ~]#

Mmmh.

Run out of ideas at the moment.

Hopefully someone else has some thoughts on things to check.

I asked Josh to connect this morning, 8:36 Arizona time. UTC is +8 from here.

If the Perl script sets from = today and to = (today + 86400 -1) then something is not ok. I looked at the code, lines 112-158 database query

I selected From, To to 25, clicked update, no report. Moved To: to 26, clicked update, got report.

@jon Actually, if you look at the sql code, lines 146-155 the comparison is:

DATETIME(disconnected_at, 'localtime') > DATETIME('$from_datestring', 'localtime', 'start of day') 
AND
DATETIME(connected_at   , 'localtime') < DATETIME('$to_datestring'  , 'localtime', 'start of day', '+86399 seconds')

The To: string adds 86399 seconds so FROM=day at 00:00:00 and TO=day plus 23:59:59

The upper case DATETIME() is a custom function, not the usual datetime() in Perl.

I don’t know Perl so probably I will open a ticket and have someone look at it.

https://bugzilla.ipfire.org/show_bug.cgi?id=12768

Per Michael’s suggestion, he asked for a raw dump of the clients.db.

Here’s the INSERTs, data is in UTC but when reported, it converts to locatime (Arizona, UTC-7)

INSERT INTO sessions VALUES('josh','2022-01-25 15:36:56','2022-01-25 15:46:55',817076,8067812);
INSERT INTO sessions VALUES('josh','2022-01-25 23:31:04','2022-01-26 00:16:18',7929864,37502892);

I am not a perl person either. So this is a wild guess. I think the logic should be similar to:

# in SQLite

[root@ipfire ~] # sqlite3
SQLite version 3.36.0 2021-06-18 18:36:39
Enter ".help" for usage hints.
Connected to a transient in-memory database.
Use ".open FILENAME" to reopen on a persistent database.

sqlite> select DATETIME('now','localtime','start of day', '+1 day', '-1 second');
2022-01-27 23:59:59

or maybe in Perl:

DATETIME('$to_datestring', 'localtime', 'start of day', '+1 day', '-1 second')

To me they are both the same (the +86399 seconds vs. the +1 day -1 second)

Jon, your original comment (I think post 2) was, “The clock goes midnight to midnight on the same day. So zero seconds total.” I just wanted to mention that the sql query is built so that if you select the same day in From: and To:, it will add 86399 seconds to the query. No worries.

1 Like