Bug: Crash after synchronizing with core.time.TimeException: Invalid ISO Extended String #2810

dploeger · 2024-09-17T08:20:05Z

Describe the bug

After synchronizing the data with --sync and vacuuming the database, the process crashes with this stack:

[Step 2/8] Performing a database consistency and integrity check on locally stored data ...Attempting to perform a database vacuum to optimise database^M
[Step 2/8] Database vacuum is complete^M
[Step 2/8] core.time.TimeException@/usr/lib/ldc/x86_64-linux-gnu/include/d/std/datetime/systime.d(9101): Invalid ISO Extended String: 2024-Sep-17 06:00:27^M
[Step 2/8] ----------------^M
[Step 2/8] ??:? [0x55ed92234da5]^M
[Step 2/8] ??:? [0x55ed92231a31]^M
[Step 2/8] ??:? [0x55ed92231692]^M
[Step 2/8] ??:? [0x55ed92259adc]^M
[Step 2/8] ??:? [0x55ed9225814f]^M
[Step 2/8] ??:? [0x55ed92259b2c]^M
[Step 2/8] ??:? [0x55ed9225814f]^M
[Step 2/8] ??:? [0x55ed92259b2c]^M
[Step 2/8] ??:? [0x55ed9225814f]^M
[Step 2/8] ??:? [0x55ed92259b2c]^M
[Step 2/8] ??:? [0x55ed9225814f]^M
[Step 2/8] ??:? [0x55ed92257ada]^M
[Step 2/8] ??:? [0x55ed922cee66]^M
[Step 2/8] ??:? [0x55ed922cb5e1]^M
[Step 2/8] ??:? void rt.dmain2._d_run_main2(char[][], ulong, extern (C) int function(char[][])*).runAll() [0x7f19050d6b7b]^M
[Step 2/8] ??:? _d_run_main2 [0x7f19050d6995]^M
[Step 2/8] ??:? _d_run_main [0x7f19050d67ed]^M
[Step 2/8] ??:? [0x7f1904d33249]^M
[Step 2/8] ??:? __libc_start_main [0x7f1904d33304]^M
[Step 2/8] ??:? [0x55ed92213100]^M
[Step 2/8] Process exited with code 1^M

Operating System Details

We're using https://hub.docker.com/r/driveone/onedrive with tag 2.5 running on 

Docker engine 

Docker version 27.2.1, build 9e34c9b

on this host:

Linux dtm-devops-p-build-06 5.15.0-122-generic #132-Ubuntu SMP Thu Aug 29 13:45:52 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux
No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 22.04.5 LTS
Release:	22.04
Codename:	jammy

Client Installation Method

From Distribution Package

OneDrive Account Type

Business | Office365

What is your OneDrive Application Version

onedrive v2.5.0

What is your OneDrive Application Configuration

# Running container as user: onedrive
# Base Args: --monitor
# Changing ownership permissions on /onedrive/data and /onedrive/conf to onedrive:onedrive
# Launching 'onedrive' as onedrive via gosu
Reading configuration file: /onedrive/conf/config
Configuration file successfully loaded
Application version                          = onedrive v2.5.0
Compiled with                                = LDC 2100
User Application Config path                 = /onedrive/conf
System Application Config path               = /etc/onedrive
Applicable Application 'config' location     = /onedrive/conf/config
Configuration file found in config location  = true - using 'config' file values to override application defaults
Applicable 'sync_list' location              = /onedrive/conf/sync_list
Applicable 'items.sqlite3' location          = /onedrive/conf/items.sqlite3
Config option 'drive_id'                     =
Config option 'sync_dir'                     = /onedrive/data
Config option 'enable_logging'               = false
Config option 'log_dir'                      = /var/log/onedrive
Config option 'disable_notifications'        = false
Config option 'skip_dir'                     =
Config option 'skip_dir_strict_match'        = false
Config option 'skip_file'                    = ~*|.~*|*.tmp|*.swp|*.partial
Config option 'skip_dotfiles'                = false
Config option 'skip_symlinks'                = false
Config option 'monitor_interval'             = 300
Config option 'monitor_log_frequency'        = 12
Config option 'monitor_fullscan_frequency'   = 12
Config option 'read_only_auth_scope'         = false
Config option 'dry_run'                      = false
Config option 'upload_only'                  = false
Config option 'download_only'                = false
Config option 'local_first'                  = false
Config option 'check_nosync'                 = false
Config option 'check_nomount'                = false
Config option 'resync'                       = false
Config option 'resync_auth'                  = false
Config option 'cleanup_local_files'          = false
Config option 'classify_as_big_delete'       = 1000
Config option 'disable_upload_validation'    = false
Config option 'disable_download_validation'  = false
Config option 'bypass_data_preservation'     = false
Config option 'no_remote_delete'             = false
Config option 'remove_source_files'          = false
Config option 'sync_dir_permissions'         = 700
Config option 'sync_file_permissions'        = 600
Config option 'space_reservation'            = 52428800
Config option 'application_id'               = <redacted>
Config option 'azure_ad_endpoint'            =
Config option 'azure_tenant_id'              =
Config option 'user_agent'                   = ISV|abraunegg|OneDrive Client for Linux/v2.5.0
Config option 'force_http_11'                = false
Config option 'debug_https'                  = false
Config option 'rate_limit'                   = 0
Config option 'operation_timeout'            = 3600
Config option 'dns_timeout'                  = 60
Config option 'connect_timeout'              = 10
Config option 'data_timeout'                 = 60
Config option 'ip_protocol_version'          = 0
Config option 'threads'                      = 8
Compile time option --enable-notifications   = false

Selective sync 'sync_list' configured        = false

Config option 'sync_business_shared_items'   = true
Config option 'Shared Files Directory'       = /onedrive/data/Files Shared With Me

Config option 'webhook_enabled'              = false



### What is your 'curl' version

```shell
There is no curl command in the container image apparently...

Where is your 'sync_dir' located

Local

What are all your system 'mount points'

overlay on / type overlay (rw,relatime,lowerdir=/var/lib/docker/overlay2/l/5JLF3RFFTJY6X5IMN37WUS5NNJ:/var/lib/docker/overlay2/l/7HTAGFZKEB5LWHIE67R4FEAPSI:/var/lib/docker/overlay2/l/62Q34FAOUU43G6FQKLZDZ747XZ:/var/lib/docker/overlay2/l/XQFOILHEZ4XYFNK72GN4RN3G3S:/var/lib/docker/overlay2/l/FXFGMUASRTB76F3TORUONTTSIU:/var/lib/docker/overlay2/l/EBQLC3ZMYKSMTOP3JETN4UW6WV,upperdir=/var/lib/docker/overlay2/cae42f9677a7fb8fd2fc5538d3799244e85944026795a7f0fb987d89569fef90/diff,workdir=/var/lib/docker/overlay2/cae42f9677a7fb8fd2fc5538d3799244e85944026795a7f0fb987d89569fef90/work)
proc on /proc type proc (rw,nosuid,nodev,noexec,relatime)
tmpfs on /dev type tmpfs (rw,nosuid,size=65536k,mode=755,inode64)
devpts on /dev/pts type devpts (rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=666)
sysfs on /sys type sysfs (ro,nosuid,nodev,noexec,relatime)
cgroup on /sys/fs/cgroup type cgroup2 (ro,nosuid,nodev,noexec,relatime,nsdelegate,memory_recursiveprot)
mqueue on /dev/mqueue type mqueue (rw,nosuid,nodev,noexec,relatime)
shm on /dev/shm type tmpfs (rw,nosuid,nodev,noexec,relatime,size=65536k,inode64)
/dev/mapper/ubuntuvg-root on /onedrive/data type ext4 (rw,relatime)
/dev/mapper/ubuntuvg-root on /onedrive/conf type ext4 (rw,relatime)
/dev/mapper/ubuntuvg-root on /etc/resolv.conf type ext4 (rw,relatime)
/dev/mapper/ubuntuvg-root on /etc/hostname type ext4 (rw,relatime)
/dev/mapper/ubuntuvg-root on /etc/hosts type ext4 (rw,relatime)
devpts on /dev/console type devpts (rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=666)
proc on /proc/bus type proc (ro,nosuid,nodev,noexec,relatime)
proc on /proc/fs type proc (ro,nosuid,nodev,noexec,relatime)
proc on /proc/irq type proc (ro,nosuid,nodev,noexec,relatime)
proc on /proc/sys type proc (ro,nosuid,nodev,noexec,relatime)
proc on /proc/sysrq-trigger type proc (ro,nosuid,nodev,noexec,relatime)
tmpfs on /proc/acpi type tmpfs (ro,relatime,inode64)
tmpfs on /proc/kcore type tmpfs (rw,nosuid,size=65536k,mode=755,inode64)
tmpfs on /proc/keys type tmpfs (rw,nosuid,size=65536k,mode=755,inode64)
tmpfs on /proc/timer_list type tmpfs (rw,nosuid,size=65536k,mode=755,inode64)
tmpfs on /proc/scsi type tmpfs (ro,relatime,inode64)
tmpfs on /sys/firmware type tmpfs (ro,relatime,inode64)
tmpfs on /sys/devices/virtual/powercap type tmpfs (ro,relatime,inode64)

What are all your local file system partition types

NAME   FSTYPE FSVER LABEL UUID FSAVAIL FSUSE% MOUNTPOINTS
loop0
loop1
loop2
loop3
loop4
loop5
loop6
loop7
loop8
loop9
loop10
loop11
sda
|-sda1
|-sda2
`-sda3
sdb

How do you use 'onedrive'

The onedrive sync folder is used for storing export data from one system and synced to a shared business folder.

Steps to reproduce the behaviour

Run onedrive with --sync --resync --resync-auth parameters

Complete Verbose Log Output

Will generate it and send the debug log to the mail adress because of possible sensitive data.

Screenshots

No response

Other Log Information or Details

No response

Additional context

No response

The text was updated successfully, but these errors were encountered:

abraunegg · 2024-09-17T08:25:54Z

@dploeger
Please build from 'source' - using 'master' and reproduce without using Docker please.

When building from source, please enable debugging:

./configure --enable-debug make clean; make;

To create a debug log output, please follow:

onedrive --sync --resync --resync-auth --verbose --verbose > debug_output.log 2>&1

Thanks.

abraunegg · 2024-09-17T09:06:25Z

@dploeger
If you are able to 'self build' Docker containers, I have created PR #2811 that adds the --enable-debug option to the Docker builds.

This is critically important to resolve this:

[Step 2/8] core.time.TimeException@/usr/lib/ldc/x86_64-linux-gnu/include/d/std/datetime/systime.d(9101): Invalid ISO Extended String: 2024-Sep-17 06:00:27^M
[Step 2/8] ----------------^M
[Step 2/8] ??:? [0x55ed92234da5]^M
[Step 2/8] ??:? [0x55ed92231a31]^M
[Step 2/8] ??:? [0x55ed92231692]^M
[Step 2/8] ??:? [0x55ed92259adc]^M
[Step 2/8] ??:? [0x55ed9225814f]^M
[Step 2/8] ??:? [0x55ed92259b2c]^M
[Step 2/8] ??:? [0x55ed9225814f]^M
[Step 2/8] ??:? [0x55ed92259b2c]^M
[Step 2/8] ??:? [0x55ed9225814f]^M
[Step 2/8] ??:? [0x55ed92259b2c]^M
[Step 2/8] ??:? [0x55ed9225814f]^M
[Step 2/8] ??:? [0x55ed92257ada]^M
[Step 2/8] ??:? [0x55ed922cee66]^M
[Step 2/8] ??:? [0x55ed922cb5e1]^M
[Step 2/8] ??:? void rt.dmain2._d_run_main2(char[][], ulong, extern (C) int function(char[][])*).runAll() [0x7f19050d6b7b]^M
[Step 2/8] ??:? _d_run_main2 [0x7f19050d6995]^M
[Step 2/8] ??:? _d_run_main [0x7f19050d67ed]^M
[Step 2/8] ??:? [0x7f1904d33249]^M
[Step 2/8] ??:? __libc_start_main [0x7f1904d33304]^M
[Step 2/8] ??:? [0x55ed92213100]^M

Once this is resolved, the reason for the crash can be understood and then fixed.

Without this resolution, it is next to impossible to pinpoint the cause & fix.

abraunegg · 2024-09-17T09:08:19Z

@dploeger
Please use the following instructions to clone this PR:

git clone https://github.com/abraunegg/onedrive.git
cd onedrive
git fetch origin pull/2811/head:pr2811
git checkout pr2811

Augment the above with the instructions here on building your own Docker container:

https://github.com/abraunegg/onedrive/blob/master/docs/docker.md#building-a-custom-docker-image

dploeger · 2024-09-17T10:23:55Z

Meh. On a second run it works without a problem. I'll keep this in mind though. Thanks!

abraunegg · 2024-09-17T10:28:55Z

No problem .. it would have been good to know what broke and where and why ....

dploeger · 2024-09-17T12:16:19Z

But now I see other problems in another run. I'll create the docker image and will use that internally. If another problem occurs, I can give you better information.

dploeger · 2024-09-17T12:26:38Z

@abraunegg Hm. --enable-debug still doesn't seem to work in the container:

Or did I misunderstand you there?

(I've build the image on the PR branch and pushed that to our internal registry to use it in the CI build)

abraunegg · 2024-09-17T19:13:34Z

@abraunegg Hm. --enable-debug still doesn't seem to work in the container:

Or did I misunderstand you there?

(I've build the image on the PR branch and pushed that to our internal registry to use it in the CI build)

You need to recompile the actual 'client' .. by either building the entire client from scratch, or using the PR and build your own Docker container from the PR, which will do this step.

When using the 'self built' container, the 'onedrive' binary will be built with --enable-debug to then give the right details.

dploeger · 2024-09-17T19:24:17Z

I've checked out the PR and ran docker build.

Isn't that what you mean with "self-built container"?

abraunegg · 2024-09-17T19:27:16Z

I've checked out the PR and ran docker build.

Isn't that what you mean with "self-built container"?

Correct ... so now, if the client crashes, the internally built 'onedrive' binary will have the correct debugging enabled to capture what is going on.

dploeger · 2024-09-17T19:37:35Z

Ohhh. It's not a parameter to the entrypoint of the container?

abraunegg · 2024-09-17T19:38:40Z

Ohhh. It's not a parameter to the entrypoint of the container?

No it is not .. which is why you have to either:

Build the client from source manually
Build a new Docker container from the PR - so that the container build process builds the client with that parameter.

dploeger · 2024-09-17T19:52:47Z

Yeah, yeah. I got that. But I added --enable-debug to the parameter list and saw the error because I misunderstood you. Will remove it tomorrow and report any stack traces. Thanks for the support!

abraunegg · 2024-09-17T22:03:42Z

@dploeger
FYI - what I have also done in the meantime is I have added the required change into 'master' , so if you use any of the 'edge' Docker tags, this 'change' should be there by default - this may assist you with this issue.

* Add isValidUTCDateTime function to validate timestamp as received from OneDrive API to ensure it is valid * Use new function before attempting to call SysTime.fromISOExtString to ensure this call will be successful

abraunegg · 2024-09-18T03:15:24Z

@dploeger
I have been looking at this issue today more deeply, and I am still trying to deduce where the issue is being introduced, however, given that there are 2 issues of the same type that has been raised, I have worked on a more generic fix.

Please can you pull this PR, and build a new Docker container from this PR:

git clone https://github.com/abraunegg/onedrive.git
cd onedrive
git fetch origin pull/2816/head:pr2816
git checkout pr2816

When running the PR, your version should be: onedrive v2.5.0-3-gf06e816 or greater within your Docker container.

dploeger · 2024-09-18T05:06:24Z

I've compiled the PR and will use that image from now on. Our pipeline runs for 4 hours though (one initial onedrive sync, generating the export and rsyncing it locally, second onedrive sync) so I can't provide faster insights I'm afraid.

abraunegg · 2024-09-18T05:07:41Z

I've compiled the PR and will use that image from now on. Our pipeline runs for 4 hours though (one initial onedrive sync, generating the export and rsyncing it locally, second onedrive sync) so I can't provide faster insights I'm afraid.

No problem - thanks for letting me know

dploeger · 2024-09-18T08:57:44Z

It now failed with this on the second sync:

  std.json.JSONException@std/json.d(315): JSONValue is not an object
  ----------------
  /usr/lib/ldc/x86_64-redhat-linux-gnu/include/d/std/exception.d:519 pure @safe noreturn std.exception.bailOut!(std.json.JSONException).bailOut(immutable(char)[], ulong, scope const(char)[]) [0x68b1e3]
  ??:? inout pure ref @safe inout(std.json.JSONValue) std.json.JSONValue.opIndex(return scope immutable(char)[]) [0x7fe4485c5a93]
  src/sync.d:6027 [0x4d3cac]
  src/sync.d:4417 [0x4d261c]
  src/sync.d:4161 [0x4d1208]
  src/sync.d:4060 [0x4d0c79]
  /usr/lib/ldc/x86_64-redhat-linux-gnu/include/d/std/parallelism.d-mixin-4114:4156 [0x68e3db]
  ??:? void std.parallelism.TaskPool.executeWorkLoop() [0x7fe4485a378d]
  ??:? thread_entryPoint [0x7fe4482da467]
  ??:? [0x7fe447f936d6]
  ??:? __clone [0x7fe448017413]

dploeger · 2024-09-18T08:57:49Z

Hope that helps

abraunegg · 2024-09-18T09:04:52Z

Hope that helps

That little part shows a 100% potentially different issue .......

dploeger · 2024-09-18T09:06:35Z

Yes. The original TimeException doesn't seem to pop up again.

dploeger · 2024-09-18T09:06:59Z

We can update this issue to better reflect it or I can open another one

abraunegg · 2024-09-18T09:35:32Z

Please raise a new bug report for tracking purposes

dploeger · 2024-09-18T10:09:50Z

This is in #2822 then. I'll close this bug then.

abraunegg · 2024-09-18T10:17:35Z

Keep this one open for the moment until 2813 is also solved.

@phlibi

* Add isValidUTCDateTime function to validate timestamp as received from OneDrive API to ensure it is valid * Use new function before attempting to call SysTime.fromISOExtString to ensure this call will be successful * If there is no timestamp in the JSON, set it to the system time * Add assertion when building an item from DB data * Add new function (isValidUTF8) to check UTF-8 validity of a string before timestamp regex check * In a --resync scenario, if the file hash is the same, use the online timestamp as source of truth * Ensure that the session URL data is a valid JSON response before use * Ensure a local time in UTC is being used if the JSON data has no date * Ensure the DB is opened in the most threadsafe manner possible * Add patch provided by @phlibi to add synchronized() around DB access methods * Align timestamp creation method with itemdb if element is missing

abraunegg · 2024-10-04T01:54:48Z

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

dploeger added the Bug Something isn't working label Sep 17, 2024

abraunegg added More Information Needed Waiting on Response labels Sep 17, 2024

dploeger closed this as completed Sep 17, 2024

abraunegg mentioned this issue Sep 17, 2024

Bug: Sync crashes/exits with core.time.TimeException: Invalid ISO Extended String #2813

Closed

abraunegg reopened this Sep 17, 2024

abraunegg changed the title ~~Bug: Crash after synchronizing~~ Bug: Crash after synchronizing with core.time.TimeException: Invalid ISO Extended String Sep 17, 2024

abraunegg added the Docker Issue label Sep 17, 2024

abraunegg added this to the v2.5.1 milestone Sep 17, 2024

abraunegg added OneDrive Business Unable to reproduce labels Sep 17, 2024

abraunegg added the PR Provided - Needs Testing label Sep 18, 2024

dploeger closed this as completed Sep 18, 2024

abraunegg reopened this Sep 18, 2024

abraunegg added Fixed and removed OneDrive Business More Information Needed PR Provided - Needs Testing Waiting on Response Unable to reproduce labels Sep 18, 2024

abraunegg linked a pull request Sep 20, 2024 that will close this issue

Fix issues #2810, #2813, #2822, #2829 #2816

Merged

abraunegg closed this as completed in #2816 Sep 26, 2024

abraunegg reopened this Sep 26, 2024

abraunegg linked a pull request Sep 26, 2024 that will close this issue

Release files for 2.5.1 #2851

Merged

abraunegg closed this as completed in #2851 Sep 26, 2024

Repository owner locked as resolved and limited conversation to collaborators Oct 4, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Bug: Crash after synchronizing with core.time.TimeException: Invalid ISO Extended String #2810

Bug: Crash after synchronizing with core.time.TimeException: Invalid ISO Extended String #2810

dploeger commented Sep 17, 2024

abraunegg commented Sep 17, 2024

abraunegg commented Sep 17, 2024

abraunegg commented Sep 17, 2024

dploeger commented Sep 17, 2024

abraunegg commented Sep 17, 2024

dploeger commented Sep 17, 2024

dploeger commented Sep 17, 2024 •

edited

Loading

abraunegg commented Sep 17, 2024

dploeger commented Sep 17, 2024

abraunegg commented Sep 17, 2024

dploeger commented Sep 17, 2024

abraunegg commented Sep 17, 2024

dploeger commented Sep 17, 2024

abraunegg commented Sep 17, 2024

abraunegg commented Sep 18, 2024

dploeger commented Sep 18, 2024

abraunegg commented Sep 18, 2024

dploeger commented Sep 18, 2024 •

edited

Loading

dploeger commented Sep 18, 2024

abraunegg commented Sep 18, 2024

dploeger commented Sep 18, 2024

dploeger commented Sep 18, 2024

abraunegg commented Sep 18, 2024

dploeger commented Sep 18, 2024

abraunegg commented Sep 18, 2024

abraunegg commented Oct 4, 2024

Bug: Crash after synchronizing with core.time.TimeException: Invalid ISO Extended String #2810

Bug: Crash after synchronizing with core.time.TimeException: Invalid ISO Extended String #2810

Comments

dploeger commented Sep 17, 2024

Describe the bug

Operating System Details

Client Installation Method

OneDrive Account Type

What is your OneDrive Application Version

What is your OneDrive Application Configuration

Where is your 'sync_dir' located

What are all your system 'mount points'

What are all your local file system partition types

How do you use 'onedrive'

Steps to reproduce the behaviour

Complete Verbose Log Output

Screenshots

Other Log Information or Details

Additional context

abraunegg commented Sep 17, 2024

abraunegg commented Sep 17, 2024

abraunegg commented Sep 17, 2024

dploeger commented Sep 17, 2024

abraunegg commented Sep 17, 2024

dploeger commented Sep 17, 2024

dploeger commented Sep 17, 2024 • edited Loading

abraunegg commented Sep 17, 2024

dploeger commented Sep 17, 2024

abraunegg commented Sep 17, 2024

dploeger commented Sep 17, 2024

abraunegg commented Sep 17, 2024

dploeger commented Sep 17, 2024

abraunegg commented Sep 17, 2024

abraunegg commented Sep 18, 2024

dploeger commented Sep 18, 2024

abraunegg commented Sep 18, 2024

dploeger commented Sep 18, 2024 • edited Loading

dploeger commented Sep 18, 2024

abraunegg commented Sep 18, 2024

dploeger commented Sep 18, 2024

dploeger commented Sep 18, 2024

abraunegg commented Sep 18, 2024

dploeger commented Sep 18, 2024

abraunegg commented Sep 18, 2024

abraunegg commented Oct 4, 2024

dploeger commented Sep 17, 2024 •

edited

Loading

dploeger commented Sep 18, 2024 •

edited

Loading